View Issue Details

IDProjectCategoryView StatusLast Update
0000046easycwmpQuestionpublic2015-07-21 10:36
Reporteradamfox Assigned Tomohamed.kallel  
PrioritynormalSeverityminorReproducibilityalways
Status resolvedResolutionno change required 
PlatformARMOSOpenWRTOS VersionBarrier Breaker
Summary0000046: easycwmpd: error occured when trying to write to the pipe
DescriptionI am posting this as a question, in case others have run into (and perhaps solved?) this issue already.

I am running easycwmpd on OpenWRT (Barrier Breaker), using the OpenWRT init script provided in the easycwmp package:

boot() {
        service_start /usr/sbin/easycwmpd --boot
}

start() {
    service_start /usr/sbin/easycwmpd --getrpcmethod
}

stop() {
    service_stop /usr/sbin/easycwmpd
}



When I run this script manually from the command-line, easycwmpd starts up normally and informs to my ACS.

However, when this init script is executed by UCI (either at boot time, or following a re-config), easycwmpd fails to inform to ACS (due to a failure writing to pipe):


Thu Mar 26 11:33:36 2015 daemon.notice easycwmpd: add event '2 PERIODIC'
Thu Mar 26 11:33:36 2015 daemon.notice easycwmpd: start session
Thu Mar 26 11:33:36 2015 daemon.notice easycwmpd: configured acs url http://test.acs.fudor.com/v1/
Thu Mar 26 11:33:36 2015 daemon.notice easycwmpd: external script init
Thu Mar 26 11:33:36 2015 daemon.notice easycwmpd: sending Inform failed
Thu Mar 26 11:33:36 2015 daemon.notice easycwmpd: external: execute apply service
Thu Mar 26 11:33:36 2015 daemon.crit easycwmpd: error occured when trying to write to the pipe
Thu Mar 26 11:33:36 2015 daemon.crit easycwmpd: error occured when trying to write to the pipe
Thu Mar 26 11:33:36 2015 daemon.notice easycwmpd: external script exit
Thu Mar 26 11:33:36 2015 daemon.crit easycwmpd: error occured when trying to write to the pipe
Thu Mar 26 11:33:36 2015 daemon.notice easycwmpd: end session failed
Thu Mar 26 11:33:36 2015 daemon.notice easycwmpd: retry session in 3840 sec, RetryCount = 692

Steps To Reproduce1) integrate easycwmp into OpenWRT per PIVA instructions (http://easycwmp.org/index.php/manual)
2) reboot device
3) logread | grep easycwmp
TagsNo tags attached.
e-mail notification

Activities

adamfox

2015-04-02 06:40

reporter   ~0000152

On the pipe write failure, errno gets set to 32 (Broken Pipe). I added a signal handler, which shows a SIGCHLD prior to the pipe write failure. So it looks like the child is dying right after the exec. I don't know yet what UCI is doing to cause this. From the log:

Wed Apr 1 14:13:38 2015 daemon.notice easycwmpd: add event '1 BOOT'
Wed Apr 1 14:13:38 2015 daemon.notice easycwmpd: configuration (re)load
Wed Apr 1 14:13:38 2015 user.emerg syslog: config_init_local(54):: easycwmp.@local[0].interface=eth0.2
Wed Apr 1 14:13:38 2015 user.emerg syslog: config_init_local(82):: easycwmp.@local[0].ubus_socket=/var/run/ubus.sock
Wed Apr 1 14:13:38 2015 user.emerg syslog: config_init_local(64):: easycwmp.@local[0].port=7574
Wed Apr 1 14:13:38 2015 user.emerg syslog: config_init_local(76):: easycwmp.@local[0].password=admin
Wed Apr 1 14:13:38 2015 user.emerg syslog: config_init_local(70):: easycwmp.@local[0].username=admin
Wed Apr 1 14:13:38 2015 user.emerg syslog: config_init_acs(177):: easycwmp.@acs[0].periodic_time=0001-01-01T00:00:00Z
Wed Apr 1 14:13:38 2015 user.emerg syslog: config_init_acs(147):: easycwmp.@acs[0].url=http://test.acs.fudor.com/v1/
Wed Apr 1 14:13:38 2015 daemon.notice easycwmpd: daemon started
Wed Apr 1 14:13:38 2015 user.emerg syslog: config_init_acs(159):: easycwmp.@acs[0].password=admin123
Wed Apr 1 14:13:38 2015 user.emerg syslog: config_init_acs(153):: easycwmp.@acs[0].username=admin123
Wed Apr 1 14:13:38 2015 daemon.notice easycwmpd: external: execute inform device_id
Wed Apr 1 14:13:38 2015 daemon.crit easycwmpd: sig_handler(): rx signo 17
Wed Apr 1 14:13:38 2015 daemon.crit easycwmpd: error occured when trying to write to the pipe (errno=32): Broken pipe
Wed Apr 1 14:13:38 2015 daemon.notice easycwmpd: external script exit
Wed Apr 1 14:13:38 2015 daemon.crit easycwmpd: error occured when trying to write to the pipe (errno=32): Broken pipe


Are there many others running easycwmp in a recent release of OpenWRT?

mohamed.kallel

2015-04-02 17:31

administrator   ~0000153

Last edited: 2015-04-02 17:32

could you provide more information.
change this line in the /usr/sbin/easycwmp script:
handle_action 2>/dev/null
to
handle_action

and then execute the command:
easycwmp json_input

what's the output of this command?

adamfox

2015-04-02 20:34

reporter   ~0000154

I have modified /usr/sbin/easycwmp as requested.

SR400-linux: # easycwmp json_input
easycwmp>

adamfox

2015-04-03 21:02

reporter   ~0000155

I am able to reproduce the problem on the command-line with the following init script:

SR400-linux: ~ # cat /etc/init.d/easycwmpd
#!/bin/sh /etc/rc.common
# Copyright (C) 2012-2014 OpenWrt.org

START=99
STOP=50
USE_PROCD=1

start_service() {
    procd_open_instance
    procd_set_param command /usr/sbin/easycwmpd -f --boot
    procd_close_instance
}

SR400-linux: ~ #


I then start the daemon with:

SR400-linux: ~ #
SR400-linux: ~ # /etc/init.d/easycwmpd start
SR400-linux: ~ #


In the log:

Fri Apr 3 11:57:53 2015 daemon.notice easycwmpd: start session
Fri Apr 3 11:57:53 2015 daemon.notice easycwmpd: configured acs url http://test52.acs.smartrg.com/v1/
Fri Apr 3 11:57:53 2015 daemon.crit easycwmpd: external_init(): execvp: /bin/sh /usr/sbin/easycwmp --json json_input
Fri Apr 3 11:57:53 2015 daemon.notice easycwmpd: sending Inform failed
Fri Apr 3 11:57:53 2015 daemon.notice easycwmpd: external: execute apply service
Fri Apr 3 11:57:53 2015 daemon.crit easycwmpd: error occured when trying to write to the pipe (errno=32): Broken pipe
Fri Apr 3 11:57:53 2015 daemon.crit easycwmpd: error occured when trying to write to the pipe (errno=32): Broken pipe
Fri Apr 3 11:57:53 2015 daemon.notice easycwmpd: external script exit
Fri Apr 3 11:57:53 2015 daemon.crit easycwmpd: error occured when trying to write to the pipe (errno=32): Broken pipe
Fri Apr 3 11:57:53 2015 daemon.notice easycwmpd: end session failed

mohamed.kallel

2015-04-04 19:19

administrator   ~0000156

Last edited: 2015-04-04 19:22

why you have added
 procd_open_instance
and
 procd_close_instance

They could be the cause of the problem
Try to start without them and see if you got the same problem

adamfox

2015-04-06 19:51

reporter   ~0000157

The problem exists with the /etc/init.d/easycwmpd that is included with easycwmp-1.1.1.

During my investigation, I found that I was able to reproduce the issue on the command-line by using procd_open_instance and procd_close_instance. I included that info in case it was useful to someone else investigating this same problem.

I will continue investigating.

mohamed.kallel

2015-04-06 22:48

administrator   ~0000158

Is it possible to have remote access to your equipment for investigation.

you can send ip address and credentials to my email address.

you can find my email address in the source code

adamfox

2015-04-07 19:27

reporter   ~0000159

I suspect that the issue is caused by a bug in procd on Barrier Breaker. I see that procd has been modified substantially in Chaos Calmer. I will try building the newer version of procd and see if it helps.

mohamed.kallel

2015-04-08 11:12

administrator   ~0000160

Last edited: 2015-04-08 11:19

I tried to run easycwmpd on your router with "/usr/sbin/easycwmpd --getrpcmethod" and the easycwmpd run properly without any problem (there is no broken pipe problem)

I tried also with the current /etc/init.d/easycwmpd script on your router and it works also (except the logger problem)

SO the problem is out of easycwmpd. The cause could be from the procd. May be procd is avoiding easycwmpd to open pipe to shell script execution. You can see that in external.c in the external_init() function. This function make a fork and open a pipe in and pipe out to communicate with shell scripts of easycwmp. May be the procd is causing some problem to the fork or to the pipes. You can contact procd maintainers for more info. Please keep me involved with your investigation results.

Please think to use easycwmp-1.1.2 instead of easycwmp-1.1.1
Please think to use a cache solution for a big data model especially when the GetParameterValue of the whole data model tree become more and more slow

mohamed.kallel

2015-04-08 15:28

administrator   ~0000161

Last edited: 2015-04-08 15:29

By the way you have a bug

SR400ac-linux: ~ # easycwmp get name "Device.ManagementServer." 0
{ "parameter": "Device.", "writable": "0" } <<============= Not good, Should not be displayed
{ "parameter": "Device.RootDataModelVersion", "writable": "0" } <<============= Not good, Should not be displayed
{ "parameter": "Device.InterfaceStackNumberOfEntries", "writable": "0" } <<============= Not good, Should not be displayed
{ "parameter": "Device.ManagementServer.", "writable": "0" }
{ "parameter": "Device.ManagementServer.EnableCWMP", "writable": "1" }
{ "parameter": "Device.ManagementServer.URL", "writable": "1" }
{ "parameter": "Device.ManagementServer.Username", "writable": "1" }
{ "parameter": "Device.ManagementServer.Password", "writable": "1" }
{ "parameter": "Device.ManagementServer.PeriodicInformEnable", "writable": "1" }
{ "parameter": "Device.ManagementServer.PeriodicInformInterval", "writable": "1" }
{ "parameter": "Device.ManagementServer.PeriodicInformTime", "writable": "1" }
{ "parameter": "Device.ManagementServer.ConnectionRequestURL", "writable": "0" }
{ "parameter": "Device.ManagementServer.ConnectionRequestUsername", "writable": "1" }
{ "parameter": "Device.ManagementServer.ConnectionRequestPassword", "writable": "1" }
{ "parameter": "Device.ManagementServer.ParameterKey", "writable": "0" }


This is because you have added params under root (Device.) in the device_root script. The following line was edited by you inorder to support parameters under the root (Device.):

 case "$1" in ""|"$DMROOT."|"$DMROOT."*)

The above line should be edited in this way

 case "$1" in ""|"$DMROOT."|"$DMROOT."*[^.])

in order to support params under the root (Device.)

mohamed.kallel

2015-04-08 16:59

administrator   ~0000163

The name of the entry function of the device_root script should not be

entry_execute_method_root_Device()

it should be

entry_execute_method_root()

You should not change it

mohamed.kallel

2015-04-08 17:00

administrator   ~0000164

Also you have to change the mechanisme of the script ( because you have added parameter under root(Device.) ), otherwise you will get wrong output in the:

easycwmp get name "" 1

adamfox

2015-04-09 00:33

reporter   ~0000165

Yes, the problem only occurs when easycwmpd is started by procd. I will try to test with the latest version of procd and see if the problem remains.

Do you know of others running easycwmpd in OpenWRT? If the issue is caused by procd, I would expect that all OpenWRT users would be affected.

Thanks for finding the bugs in my data model and scripts. I will fix them.

adamfox

2015-04-14 02:19

reporter   ~0000185

I made a build with the last version of freecwmp, and I do not see this problem. Obviously the easycwmpd code has diverged significantly since then. I will continue investigating.

Are other people successfully running easycwmpd in OpenWRT? If so, I would like to know the working version of procd.

Issue History

Date Modified Username Field Change
2015-03-30 21:47 adamfox New Issue
2015-04-02 06:40 adamfox Note Added: 0000152
2015-04-02 17:31 mohamed.kallel Note Added: 0000153
2015-04-02 17:32 mohamed.kallel Note Edited: 0000153
2015-04-02 20:34 adamfox Note Added: 0000154
2015-04-03 21:02 adamfox Note Added: 0000155
2015-04-04 19:19 mohamed.kallel Note Added: 0000156
2015-04-04 19:22 mohamed.kallel Note Edited: 0000156
2015-04-06 19:51 adamfox Note Added: 0000157
2015-04-06 22:48 mohamed.kallel Note Added: 0000158
2015-04-07 19:27 adamfox Note Added: 0000159
2015-04-08 11:12 mohamed.kallel Note Added: 0000160
2015-04-08 11:19 mohamed.kallel Note Edited: 0000160
2015-04-08 15:28 mohamed.kallel Note Added: 0000161
2015-04-08 15:29 mohamed.kallel Note Edited: 0000161
2015-04-08 16:59 mohamed.kallel Note Added: 0000163
2015-04-08 17:00 mohamed.kallel Note Added: 0000164
2015-04-09 00:33 adamfox Note Added: 0000165
2015-04-14 02:19 adamfox Note Added: 0000185
2015-07-21 10:36 mohamed.kallel Status new => resolved
2015-07-21 10:36 mohamed.kallel Resolution open => no change required
2015-07-21 10:36 mohamed.kallel Assigned To => mohamed.kallel